Static and Dynamic Analysis at JPL Klaus Havelund

  • Slides: 64
Download presentation
Static and Dynamic Analysis at JPL Klaus Havelund

Static and Dynamic Analysis at JPL Klaus Havelund

Mars Science Laboratory (MSL) • • • planned launch 2011 biggest rover so far

Mars Science Laboratory (MSL) • • • planned launch 2011 biggest rover so far to be sent to Mars programmer team of 30 testing team of 10+ people programming language is C, 3 M LOC highly multi-threaded (over 160 threads) 2

specification and programming Let’s see … a command should always succeed … program input

specification and programming Let’s see … a command should always succeed … program input output 3

specification and programming formal specification program input output 4

specification and programming formal specification program input output 4

specification and programming formal specification relationship program input output 5

specification and programming formal specification relationship program input output 5

specification and programming code generation: -from state machines -graphical -textual -from data formats (XML)

specification and programming code generation: -from state machines -graphical -textual -from data formats (XML) formal specification refinement program input output 6

specification and programming formal specification model checking [](request -> <>response) static analysis abstraction program

specification and programming formal specification model checking [](request -> <>response) static analysis abstraction program input output 7

specification and programming Good practice analysis using commercial static analyzers. formal specification static analysis

specification and programming Good practice analysis using commercial static analyzers. formal specification static analysis program input output 8

a checkable Java coding standard 9

a checkable Java coding standard 9

why a standard? two perspectives • more reliable code • code that is easier

why a standard? two perspectives • more reliable code • code that is easier to read, leading to – code that is easier to develop – code that is easier to maintain – code that is easier to share style 10

the choices • • • industry standard organizational standard project standard personal standard no

the choices • • • industry standard organizational standard project standard personal standard no standard good bad 11

basic questions 1. do we need to agree on a standard? carefully designed? or

basic questions 1. do we need to agree on a standard? carefully designed? or lots of rules, which can be turned on/off? 2. should it be 100% checkable? 3. do we care about naming, style, doc? 4. how many rules? 12

C coding standard 13

C coding standard 13

14

14

15

15

16

16

free tools coding error checker coding standard checkers 17

free tools coding error checker coding standard checkers 17

18

18

19

19

20

20

specification and programming formal specification dynamic analysis program input output 21

specification and programming formal specification dynamic analysis program input output 21

model-based testing

model-based testing

model-based testing http: //spinroot. com/swarm/index. html do : : mkdir : : cd dir

model-based testing http: //spinroot. com/swarm/index. html do : : mkdir : : cd dir : : rm file : : . . … od reference file system SPIN real file system abstract state abstract 23

specification and programming formal specification runtime verification program input output 24

specification and programming formal specification runtime verification program input output 24

tool-based log file analysis

tool-based log file analysis

problems with testing FSW • flight software engineers work under tight schedules: hard to

problems with testing FSW • flight software engineers work under tight schedules: hard to access. • system = hardware + software: it is cumbersome to run. • difficult to determine what events to monitor. A . h . c . h B 26

separation of concerns log log 27

separation of concerns log log 27

architecture log Log. Maker [e 1, e 2, …, en] Log. Scope spec violations

architecture log Log. Maker [e 1, e 2, …, en] Log. Scope spec violations 28

command execution command dispatch failure success failure 29

command execution command dispatch failure success failure 29

? example log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time :

? example log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } EVR 7309 { message : = "Dispatched immediate command POWER_HOUSEKEEPING: number=4, seconds=789006392, subseconds=1073741824. " Dispatch : = "POWER_HOUSEKEEPING" Time : = 51708322925696 name : = "CMD_DISPATCH" level : = "COMMAND" Number : = "4” }. . . EVR 7311 { name : = "POWER_SEND_REQUEST" Time : = 51708322925696 message : = "power_queue_card_requestsending request to PAM 0. " level : = "DIAGNOSTIC” } EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } EVR 7313 { name : = "PWR_REQUEST_CALLBACK" Time : = 51708322944128 message : = "power_card_request FPGA request successfully sent to RPAM A. " level : = "DIAGNOSTIC” } CHANNEL 7314 { channel. Id : = "PWR-3049" DNChange : = 67 dn. Unsigned. Value : = 1600 type : = "UNSIGNED_INT" Time : = 51708323217408 Channel. Name : = "PWR-BCB 1 -AMP” }. . . COMMAND 9626 { Args : = ['set_device(1)', 'TRUE'] Time : = 51708372934400 Stem : = "RUN_COMMAND" Number : = "18" type : = "FSW” } EVR 9627 { message : = "Validation failed for command RUN_COMMAND: number=18. " Dispatch. Failure : = "RUN_COMMAND" Time : = 51708372934499 name : = "CMD_DISPATCH_VALIDATION_FAILURE" level : = "COMMAND" Number : = "18” }. . . 30

? example log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time :

? example log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } EVR 7309 { message : = "Dispatched immediate command POWER_HOUSEKEEPING: number=4, seconds=789006392, subseconds=1073741824. " Dispatch : = "POWER_HOUSEKEEPING" Time : = 51708322925696 name : = "CMD_DISPATCH" level : = "COMMAND" Number : = "4” }. . . EVR 7311 { name : = "POWER_SEND_REQUEST" Time : = 51708322925696 message : = "power_queue_card_requestsending request to PAM 0. " level : = "DIAGNOSTIC” } EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } EVR 7313 { name : = "PWR_REQUEST_CALLBACK" Time : = 51708322944128 message : = "power_card_request FPGA request successfully sent to RPAM A. " level : = "DIAGNOSTIC” } CHANNEL 7314 { channel. Id : = "PWR-3049" DNChange : = 67 dn. Unsigned. Value : = 1600 type : = "UNSIGNED_INT" Time : = 51708323217408 Channel. Name : = "PWR-BCB 1 -AMP” }. . . COMMAND 9626 { Args : = ['set_device(1)', 'TRUE'] Time : = 51708372934400 Stem : = "RUN_COMMAND" Number : = "18" type : = "FSW” } EVR 9627 { message : = "Validation failed for command RUN_COMMAND: number=18. " Dispatch. Failure : = "RUN_COMMAND" Time : = 51708372934499 name : = "CMD_DISPATCH_VALIDATION_FAILURE" level : = "COMMAND" Number : = "18” }. . . 31

example log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : =

example log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } EVR 7309 { message : = "Dispatched immediate command POWER_HOUSEKEEPING: number=4, seconds=789006392, subseconds=1073741824. " Dispatch : = "POWER_HOUSEKEEPING" Time : = 51708322925696 name : = "CMD_DISPATCH" level : = "COMMAND" Number : = "4” }. . . EVR 7311 { name : = "POWER_SEND_REQUEST" Time : = 51708322925696 message : = "power_queue_card_requestsending request to PAM 0. " level : = "DIAGNOSTIC” } EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } EVR 7313 { name : = "PWR_REQUEST_CALLBACK" Time : = 51708322944128 message : = "power_card_request FPGA request successfully sent to RPAM A. " level : = "DIAGNOSTIC” } ? CHANNEL 7314 { channel. Id : = "PWR-3049" DNChange : = 67 dn. Unsigned. Value : = 1600 type : = "UNSIGNED_INT" Time : = 51708323217408 Channel. Name : = "PWR-BCB 1 -AMP” }. . . COMMAND 9626 { Args : = ['set_device(1)', 'TRUE'] Time : = 51708372934400 Stem : = "RUN_COMMAND" Number : = "18" type : = "FSW” } EVR 9627 { message : = "Validation failed for command RUN_COMMAND: number=18. " Dispatch. Failure : = "RUN_COMMAND" Time : = 51708372934499 name : = "CMD_DISPATCH_VALIDATION_FAILURE" level : = "COMMAND" Number : = "18” }. . . 32

specification languages for trace analysis • • • programming languages (Python at JPL) state

specification languages for trace analysis • • • programming languages (Python at JPL) state machines regular expressions most commonly used “formal” trace logics temporal logic grammars 33

the first scripture trigger consequences look: DRILL_DMP evr(CMD_DISPATCH, positive) evr(CMD_COMPLETED_SUCCCESS, positive) evr(CMD_COMPLETED_FAILURE, negative) chan(id:

the first scripture trigger consequences look: DRILL_DMP evr(CMD_DISPATCH, positive) evr(CMD_COMPLETED_SUCCCESS, positive) evr(CMD_COMPLETED_FAILURE, negative) chan(id: CMD-0004, positive, contains opcode of last immediate command) chan(id: CMD-0007, positive) chan(id: CMD-0001, negative) chan(id: CMD-0009, negative) prod(name: Drill. All, 1, *) 34

property P 1: Whenever a flight software command is issued, then eventually an EVR

property P 1: Whenever a flight software command is issued, then eventually an EVR should indicate success of that command 35

recall log COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem

recall log COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } . . . EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } 36

recall log COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem

recall log COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } . . . P 1: Whenever a COMMAND is issued with the Type field having the value "FSW”, the Stem field (command name) having some unknown value x, and the Number field having some unknown value y, then eventually an EVR should occur, with the field Success mapped to x and the Number field mapped to y. EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } 37

recall log COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem

recall log COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } . . . pattern P 1: COMMAND{Type: "FSW", Stem: x, Number: y} => EVR{Success: x, Number: y} EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } 38

pattern P 1: COMMAND{Type: "FSW", Stem: x, Number: y} => EVR{Success: x, Number: y}

pattern P 1: COMMAND{Type: "FSW", Stem: x, Number: y} => EVR{Success: x, Number: y} 39

pattern syntax pattern : : = 'pattern' NAME ': ' event '=>' consequence :

pattern syntax pattern : : = 'pattern' NAME ': ' event '=>' consequence : : = event | '!' event | '[' consequence 1, . . . , consequencen ']’ | ‘{' consequence 1, . . . , consequencen ‘}' 40

property P 2: Whenever a COMMAND is issued with the Type field having the

property P 2: Whenever a COMMAND is issued with the Type field having the value "FSW”, the Stem field (command name) having some unknown value x, and the Number field having some unknown value y, Then an EVR should thereafter not occur, with the field Failure mapped to x and the Number field mapped to y. pattern P 2: COMMAND{Type: "FSW", Stem: x, Number: y} => ! EVR{Failure: x, Number: y} 41

pattern syntax pattern : : = 'pattern' NAME ': ' event '=>' consequence :

pattern syntax pattern : : = 'pattern' NAME ': ' event '=>' consequence : : = event | '!' event | '[' consequence 1, . . . , consequencen ']’ | ‘{' consequence 1, . . . , consequencen ‘}' 42

property P 3: Whenever a flight software command is issued, there should follow a

property P 3: Whenever a flight software command is issued, there should follow a dispatch and then exactly one success. No dispatch failure before the dispatch, and no failure between dispatch and success. 43

formalization pattern P 3: COMMAND{Type: "FSW", Stem: x, Number: y} => [ ! EVR{Dispatch.

formalization pattern P 3: COMMAND{Type: "FSW", Stem: x, Number: y} => [ ! EVR{Dispatch. Failure: x, Number: y}, EVR{Dispatch: x, Number: y}, ! EVR{Failure: x, Number: y}, EVR{Success: x, Number: y}, ! EVR{Success: x, Number: y} ] 44

expressed in first order LTL 45

expressed in first order LTL 45

Python predicate definitions {: def within(t 1, t 2, max): return (t 2 -t

Python predicate definitions {: def within(t 1, t 2, max): return (t 2 -t 1) <= max : } pattern P 6: COMMAND{Type: "FSW", Stem: x, Number: y, Time: t 1} where {: x. startswith("PWR_”) : } => EVR{Success: x, Number: y, Time: t 2} where within(t 1, t 2, 10000) 46

scoped version of P 4 pattern P 9: COMMAND{Type: "FSW", Stem: x, Number: y}

scoped version of P 4 pattern P 9: COMMAND{Type: "FSW", Stem: x, Number: y} => { EVR{Dispatch: x, Number: y}, [ EVR{Success: x, Number: y}, ! EVR{Success: x, Number: y} ], ! EVR{Dispatch. Failure: x, Number: y}, ! EVR{Failure: x, Number: y} } upto COMMAND{Type: "FSW"} 47

from patterns to automata • temporal patterns are translated into parameterized universal automata •

from patterns to automata • temporal patterns are translated into parameterized universal automata • automaton language more expressive • user can use both, in practice only temporal patterns have been used for testing MSL 48

recall P 3 pattern P 3: COMMAND{Type: "FSW", Stem: x, Number: y} => [

recall P 3 pattern P 3: COMMAND{Type: "FSW", Stem: x, Number: y} => [ ! EVR{Dispatch. Failure: x, Number: y}, EVR{Dispatch: x, Number: y}, ! EVR{Failure: x, Number: y}, EVR{Success: x, Number: y}, ! EVR{Success: x, Number: y} ] 49

automaton A_P 3 { always S 1 { COMMAND{Type: "FSW", Stem: x, Number: y}

automaton A_P 3 { always S 1 { COMMAND{Type: "FSW", Stem: x, Number: y} => S 2(x, y) } hot state S 2(x, y) { EVR{Dispatch. Failure: x, Number: y} => error EVR{Dispatch: x, Number: y} => S 3(x, y) } hot state S 3(x, y) { EVR{Failure: x, Number: y} => error EVR{Success: x, Number: y} => S 4(x, y) } state S 4(x, y) { EVR{Success: x, Number: y} => error } } 50

51

51

recall log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : =

recall log. . . COMMAND 7308 { Args : = ['CLEAR_RELAY_PYRO_STATUS'] Time : = 51708322925696 Stem : = "POWER_HOUSEKEEPING" Number : = "4" type : = "FSW” } EVR 7309 { message : = "Dispatched immediate command POWER_HOUSEKEEPING: number=4, seconds=789006392, subseconds=1073741824. " Dispatch : = "POWER_HOUSEKEEPING" Time : = 51708322925696 name : = "CMD_DISPATCH" level : = "COMMAND" Number : = "4” }. . . EVR 7311 { name : = "POWER_SEND_REQUEST" Time : = 51708322925696 message : = "power_queue_card_requestsending request to PAM 0. " level : = "DIAGNOSTIC” } EVR 7312 { message : = "Successfully completed command POWER_HOUSEKEEPING: number=4. " Success : = "POWER_HOUSEKEEPING" Time : = 51708322944128 name : = "CMD_COMPLETED_SUCCESS" level : = "COMMAND" Number : = "4” } EVR 7313 { name : = "PWR_REQUEST_CALLBACK" Time : = 51708322944128 message : = "power_card_request FPGA request successfully sent to RPAM A. " level : = "DIAGNOSTIC” } CHANNEL 7314 { channel. Id : = "PWR-3049" DNChange : = 67 dn. Unsigned. Value : = 1600 type : = "UNSIGNED_INT" Time : = 51708323217408 Channel. Name : = "PWR-BCB 1 -AMP” }. . . COMMAND 9626 { Args : = ['set_device(1)', 'TRUE'] Time : = 51708372934400 Stem : = "RUN_COMMAND" Number : = "18" type : = "FSW” } EVR 9627 { message : = "Validation failed for command RUN_COMMAND: number=18. " Dispatch. Failure : = "RUN_COMMAND" Time : = 51708372934499 name : = "CMD_DISPATCH_VALIDATION_FAILURE" level : = "COMMAND" Number : = "18” }. . . 52

log in Python log = [ { "OBJ_TYPE" : "COMMAND", "Args" : ['CLEAR_RELAY_PYRO_STATUS'], "Time"

log in Python log = [ { "OBJ_TYPE" : "COMMAND", "Args" : ['CLEAR_RELAY_PYRO_STATUS'], "Time" : 51708322925696, "Stem" : "POWER_HOUSEKEEPING", "Number" : "4", "Type" : "FSW" }, … { "OBJ_TYPE" : "EVR", "name" : "PWR_REQUEST_CALLBACK", "Time" : 51708322944128, "message" : "power_card_request - FPGA request successfully sent to RPAM A. ", "level" : "DIAGNOSTIC" }, … ] 53

running Log. Scope import logscope log = extract. Log(…) obs = logscope. Observer("specs/rv-tutorial") obs.

running Log. Scope import logscope log = extract. Log(…) obs = logscope. Observer("specs/rv-tutorial") obs. monitor(log) 54

55

55

specification learning • writing specs is time consuming • often hard come up with

specification learning • writing specs is time consuming • often hard come up with properties • one approach is to use already generated log files to “get ideas” • in the extreme case, specifications can be automatically generated from log files 56

architecture spec yes learner monitor no: … … logs 57

architecture spec yes learner monitor no: … … logs 57

learner API import logscope log 1 = … ; log 2 = … ;

learner API import logscope log 1 = … ; log 2 = … ; learner = logscope. Concrete. Learner(“P”) learner. learnlog(log 1) learner. learnlog(log 2) learner. dump. Spec(sfile) log 3 = … ; learner = logscope. Concrete. Learner(“P”, sfile) learner. learnlog(log 3) learner. dump. Spec(sfile) log 4 = … ; obs = logscope. Observer(sfile) obs. monitor(log 4) 58

59

59

the learned spec using step and success states 60

the learned spec using step and success states 60

conclusions • use of static analysis is now required for flight missions. • model-based

conclusions • use of static analysis is now required for flight missions. • model-based testing is used by La. RS group to test file system – for real. • log analysis support shows promise. • what’s next? : runtime verification, interaction between static and dynamic analysis, specification learning, trace visualization. 61

combining static and dynamic analysis program + spec static analyzer proof obligations monitor the

combining static and dynamic analysis program + spec static analyzer proof obligations monitor the proof obligations 62

RMOR monitor File. Monitor { symbol open = after call(main. c: openfile); symbol read

RMOR monitor File. Monitor { symbol open = after call(main. c: openfile); symbol read = after call(main. c: readfile); symbol close = after call(main. c: closefile); symbol send = before call(main. c: senddata); symbol end = before call(main. c: finish); state closed {when open -> unread; } state unread {when read -> read; } state read {when send => error; } super opened [unread, read] { when end => error; when close -> closed; } Aspect. C like instrumentation state machine specification } 63

thanks for listening! 64

thanks for listening! 64