CPAM log example for a good card read and door opening

[Gerald Burgess]

Here’s how to see what the gateway is seeing in real time.

First you’ll need to turn on the ssh daemon on the gateway.  You do this by connecting to the gateway’s web interface and logging in.  You’ll get to the networking page.  Once you are there, change your URL to say “ https://<ipaddress>/tac.shtml”.  On the page that will come up  click the ‘start sshd’ button.  A popup will appear.

You will then be able to start up an ssh client (I use putty myself) and log in using the normal gwadmin credentials.

Change your directory over to /var/applog

# cd /var/applog

Now you’ll want to ‘tail’ all the log files in the directory.

# tail –f *log*

This will show you the log text as it is being fed into the logs.  It can get lengthy, so you will probably want to set your SSH client to send the output to a file.  You can at least see things happening in real time.

One of the first things you’ll see are events in the acev.log.1 file then the bp_msg log will show the processing of whatever data we got.  After that the dsm_exec log shows what happens when we look the credential up and acev.log.1 is where you see the xml that is generated for the event so the gateway can send it back to the CPAM server.  The bp_msg log will pick up the post event processing and finally the dsm_exec log shows the relock steps being processed.

Here's an example:

==> acev.log.1 <==

12/06/12 17:47:35.459 LOG_DBG[1890]acev_gen_event(): got event id 0x0400001f

12/06/12 17:47:35.497 LOG_DBG[1890]acev_gen_event(): got event id 0x03000109

12/06/12 17:47:35.578 LOG_DBG[1890]acev_gen_event(): got event id 0x01000008

==> bp_msg.log.1 <==

12/06/12 17:47:35.431 LOG_DBG[1705]process_card_event(): InterfaceEvent from card 1. IntfType 4, Index 1, Ev 31

12/06/12 17:47:35.432 LOG_INFO[1656]post_raw_intf_event(): Posting raw IntfEvent 0x400001f for m00/rdr01. EvLen 24, InfoLen 8

12/06/12 17:47:35.432 LOG_INFO[0275]acev_post_event(): ev_len 176 acev_evinfo_t 156 acev_svc_t 172 ix 216

12/06/12 17:47:35.433 LOG_INFO[0696]reader_ev_handler(): rd_cred:Got all 1 frames. Decoding..

12/06/12 17:47:35.434 LOG_DBG[1120]rd_cred_get_card_data(): PROCESSING Reader data frames = 1 devtmplid = 8650780

12/06/12 17:47:35.434 LOG_DBG[1123]rd_cred_get_card_data(): Input frm  0 size = 26

12/06/12 17:47:35.436 LOG_DBG[2007]rd_cred_get_dev_cred_ref_list(): Got the dev tmpl id match

12/06/12 17:47:35.436 LOG_DBG[0792]rd_cred_get_card_data_one(): *** size of cred data: 26

12/06/12 17:47:35.437 LOG_DBG[0805]rd_cred_get_card_data_one(): *** tmpl len: 26

12/06/12 17:47:35.437 LOG_DBG[0806]rd_cred_get_card_data_one(): *** tmpl type: 1

12/06/12 17:47:35.438 LOG_DBG[0807]rd_cred_get_card_data_one(): *** tmpl name:

12/06/12 17:47:35.438 LOG_DBG[0809]rd_cred_get_card_data_one(): *** eval mode return: 1

12/06/12 17:47:35.439 LOG_DBG[0044]rd_cred_wg_decode(): InputLen = 26 data= 0x9b, 0x84, 0xe0, 0x40, 0x0

12/06/12 17:47:35.439 LOG_DBG[0667]rd_cred_wg_verify_parity(): Expected EVEN Pairty no_ones = 6

12/06/12 17:47:35.440 LOG_DBG[0674]rd_cred_wg_verify_parity(): Expected ODD Pairty no_ones = 5

12/06/12 17:47:35.440 LOG_DBG[0062]rd_cred_wg_decode(): *** size of field data: 16

12/06/12 17:47:35.441 LOG_DBG[0064]rd_cred_wg_decode(): *** value of field data: 0x0 0x0 0x0 0x0 0x0

12/06/12 17:47:35.441 LOG_DBG[0357]rd_cred_process_wg_tmpl(): libif:wg:tmplid  = 8650756 

12/06/12 17:47:35.442 LOG_DBG[0363]rd_cred_process_wg_tmpl(): libif:wg:cardid len = 16, cardid = 0x0 0x0 0x0 0x9c0

12/06/12 17:47:35.442 LOG_DBG[0367]rd_cred_process_wg_tmpl(): libif:wg:facility len = 8, facility = 0x0 0x37

12/06/12 17:47:35.443 LOG_INFO[0705]reader_ev_handler(): rd_cred: Duress Keys in DevTmpl = 0

12/06/12 17:47:35.443 LOG_DBG[0478]convert_4bit_to_ascii(): rd_cred: 4bit keys = 0x0, 0x0 0x0 0x0 0x0 0x0

12/06/12 17:47:35.444 LOG_DBG[0503]convert_4bit_to_ascii(): rd_cred: 4bit-data ASCIId-1: keys = 0x0, 0x0 0x0 0x0 0x0 0x0

12/06/12 17:47:35.445 LOG_DBG[0716]reader_ev_handler(): rd_cred: number of decode data sets = 1

12/06/12 17:47:35.446 LOG_DBG[0719]reader_ev_handler(): rd_cred: cardid len = 16 facility len = 8

12/06/12 17:47:35.446 LOG_DBG[0723]reader_ev_handler(): rd_cred: site = 0 key = 0,duress = 0

12/06/12 17:47:35.447 LOG_DBG[0728]reader_ev_handler(): rd_cred: keys = 0x0, 0x0 0x0 0x0 0x0 0x0

12/06/12 17:47:35.447 LOG_INFO[0186]post_device_event(): Posting Device Event 0x3000109 for m00/rdr01/reader

12/06/12 17:47:35.448 LOG_INFO[0275]acev_post_event(): ev_len 264 acev_evinfo_t 156 acev_svc_t 172 ix 304

12/06/12 17:47:35.614 LOG_INFO[3596]handle_device_command(): Command 4106 for device m00/rdr01/reader

12/06/12 17:47:35.615 LOG_INFO[0938]reader_cmd_handler(): GrantAccess issued on m00/rdr01 with profile 1

12/06/12 17:47:35.665 LOG_INFO[3596]handle_device_command(): Command 4142 for device m00/output01/lock

12/06/12 17:47:35.666 LOG_INFO[2253]lock_cmd_handler(): Unlock issued on m00/output01

12/06/12 17:47:35.677 LOG_INFO[1767]process_command_resp(): CMDResp: Card 1, Cookie 2000000b, Type 4, Index 1, Resp 1, Infolen 0

12/06/12 17:47:35.678 LOG_INFO[0833]post_command_response(): Posting CmdResp. Command 4106, Dev m00/rdr01/reader, RespCode 1, AppId 1, SvcId 5, Infolen 0

12/06/12 17:47:35.679 LOG_DBG[1705]process_card_event(): InterfaceEvent from card 1. IntfType 6, Index 1, Ev 25

12/06/12 17:47:35.679 LOG_INFO[1656]post_raw_intf_event(): Posting raw IntfEvent 0x4000019 for m00/output01. EvLen 16, InfoLen 0

12/06/12 17:47:35.680 LOG_INFO[0275]acev_post_event(): ev_len 168 acev_evinfo_t 156 acev_svc_t 172 ix 208

12/06/12 17:47:35.680 LOG_INFO[0186]post_device_event(): Posting Device Event 0x301010a for m00/output01/lock

12/06/12 17:47:35.681 LOG_INFO[0275]acev_post_event(): ev_len 172 acev_evinfo_t 156 acev_svc_t 172 ix 212

12/06/12 17:47:35.684 LOG_INFO[1767]process_command_resp(): CMDResp: Card 1, Cookie 2000000c, Type 6, Index 1, Resp 1, Infolen 0

12/06/12 17:47:35.685 LOG_INFO[0833]post_command_response(): Posting CmdResp. Command 4142, Dev m00/output01/lock, RespCode 1, AppId 1, SvcId 5, Infolen 0

==> dsm_exec.log.1 <==

12/06/12 17:47:35.544 LOG_DBG[5345]main(): Got Reader Event!!

12/06/12 17:47:35.545 LOG_DBG[5357]main(): Reader Data, cred_tmpl_id: 8650756, cardid_len: 16, cardid[0]: 0, cardid[1]: 0, cardid[2]: 0, cardid[3]: 2496

12/06/12 17:47:35.545 LOG_DBG[5359]main(): Reader Data, facility code: 55

12/06/12 17:47:35.546 LOG_DBG[5361]main(): Reader Key Pad key_num: 0

12/06/12 17:47:35.547 LOG_DBG[5363]main(): Reader Key Pad duress_key_num: 0

12/06/12 17:47:35.547 LOG_DBG[5413]main(): Found Reader m00/rdr01/reader in Door Id: 0

12/06/12 17:47:35.548 LOG_DBG[5636]main(): Copying the Reader data to IPC layer!!

12/06/12 17:47:35.548 LOG_DBG[5639]main(): Type: 2

12/06/12 17:47:35.549 LOG_DBG[0360]dsm_door_thread_input_mesg(): !! Sending Request to Door thread: 0

12/06/12 17:47:35.549 LOG_DBG[5229]main(): Waiting for Event Input

12/06/12 17:47:35.551 LOG_DBG[1174]invoke_dsm(): Type: 2

12/06/12 17:47:35.551 LOG_DBG[1175]invoke_dsm(): In invoke_dsm(), type: 2, input: 0, input_value: 0

12/06/12 17:47:35.552 LOG_DBG[0086]dispatch_door_device_event(): device_type:1

12/06/12 17:47:35.552 LOG_DBG[2868]simple_dsm_handle_reader_input(): Door Id: 0, Simple DSM handle Reader Input

12/06/12 17:47:35.553 LOG_DBG[2917]simple_dsm_handle_reader_input(): Door Id: 0, Reader Input key_num: 0, duress_key_num: 0, duress:

12/06/12 17:47:35.554 LOG_DBG[1240]dsm_door_cred_lookup_func(): Doing Special/Temp Credential DB Lookup!!

12/06/12 17:47:35.555 LOG_DBG[1244]dsm_door_cred_lookup_func(): Badge Hi: 0, Lo: 2496, Cred_tmplId: 8650756

12/06/12 17:47:35.555 LOG_DBG[1282]dsm_door_cred_lookup_func(): Doing Credential DB Lookup!!

12/06/12 17:47:35.556 LOG_DBG[1286]dsm_door_cred_lookup_func(): Badge Hi: 0, Lo: 2496, Cred_tmplId: 8650756

12/06/12 17:47:35.556 LOG_DBG[1291]dsm_door_cred_lookup_func(): Found Credential DB Lookup!!

12/06/12 17:47:35.557 LOG_DBG[1308]dsm_door_cred_lookup_func(): Found Badge In DB!!

12/06/12 17:47:35.557 LOG_DBG[1312]dsm_door_cred_lookup_func(): Badge Hi: 0, Lo: 2496, Cred_tmplId: 8650756

12/06/12 17:47:35.558 LOG_DBG[0698]dsm_cred_analyze_badge_for_access(): Badge in DB has facility Code: 55

12/06/12 17:47:35.558 LOG_DBG[0902]dsm_cred_analyze_badge_for_access(): Number of Access Level Ids in badge: 2

12/06/12 17:47:35.559 LOG_DBG[0903]dsm_cred_analyze_badge_for_access(): Access Level Ids in badge:

12/06/12 17:47:35.560 LOG_DBG[0916]dsm_cred_analyze_badge_for_access(): 8388619 8388609

12/06/12 17:47:35.560 LOG_DBG[1002]dsm_polcfg_alexec(): Current Time yy 2012 mm 12 dd 06 hr 17 min 47 sec 35 doy 341 woy 49 tz -0800 PST

12/06/12 17:47:35.561 LOG_DBG[1012]dsm_polcfg_alexec(): door /Nicira/gw_FOC1550833R/Door/door01 alid 8388619 alid cnt 2

12/06/12 17:47:35.561 LOG_DBG[0877]dsm_polcfg_alexec_onealid(): al sched 8454147 deact 0 door /Nicira/gw_FOC1550833R/Door/door01 door /Nicira/gw_FOC1550833R/Door/door01 strncmp 0

12/06/12 17:47:35.562 LOG_DBG[0945]dsm_polcfg_alexec_onealid(): reason 2 sched 8454147 timemap 8585219 handle 0

12/06/12 17:47:35.563 LOG_DBG[1033]dsm_polcfg_alexec(): permit reason 2

12/06/12 17:47:35.563 LOG_DBG[1052]dsm_polcfg_alexec(): One permit No deny all ok 2

12/06/12 17:47:35.564 LOG_DBG[0930]dsm_cred_analyze_badge_for_access(): AL Policy logic returns: access_reason_code: 2, access_level_id: 8388619

12/06/12 17:47:35.564 LOG_DBG[0972]dsm_cred_analyze_badge_for_access(): Getting reason: 2 from dsm_polcfg_alexec()

12/06/12 17:47:35.565 LOG_DBG[0974]dsm_cred_analyze_badge_for_access(): Allow access to Door for this credential due to AL allow!!

12/06/12 17:47:35.565 LOG_DBG[3016]simple_dsm_handle_reader_input(): Getting Allow from Lookup

12/06/12 17:47:35.566 LOG_DBG[3020]simple_dsm_handle_reader_input(): Getting Allow from Local Authentication!!

12/06/12 17:47:35.566 LOG_DBG[2056]dsm_grant_access(): Granted Access! Door: door01, Badge Hi: 0, Low: 2496, Cred Temp id: 8650756, Pin Keys:

12/06/12 17:47:35.567 LOG_DBG[0200]dsm_device_reader_cmd():  Reader cmd for device: m00/rdr01/reader

12/06/12 17:47:35.567 LOG_DBG[0229]dsm_device_reader_cmd(): done Reader cmd: 4106 profile: 1

12/06/12 17:47:35.568 LOG_DBG[0102]dsm_device_lock_cmd(): Lock_cmd for device: m00/output01/lock

12/06/12 17:47:35.569 LOG_DBG[0117]dsm_device_lock_cmd(): done lock cmd 4142 156

12/06/12 17:47:35.570 LOG_INFO[0275]acev_post_event(): ev_len 296 acev_evinfo_t 156 acev_svc_t 172 ix 336

12/06/12 17:47:35.571 LOG_DBG[0667]dsm_door_ev_gen(): Generating Door: door01 Event Id: 0x01000008, Grant Access

12/06/12 17:47:35.572 LOG_DBG[0556]simple_dsm_start_relock_timer(): Simple DSM Start Relock Timeout, Door Id: 0

12/06/12 17:47:35.572 LOG_DBG[0490]simple_dsm_start_timer(): Door Id: 0, Started Timer: Relock Timer, TimeOut (in msec): 5000!!!!

12/06/12 17:47:35.573 LOG_DBG[0673]simple_dsm_start_reader_grant_access_timer(): Simple DSM Start Reader Grant Access Timeout, Door Id: 0, reader: m00/rdr01/reader

12/06/12 17:47:35.573 LOG_DBG[0490]simple_dsm_start_timer(): Door Id: 0, Started Timer: Door Grant Access Timer, TimeOut (in msec): 5000!!!!

12/06/12 17:47:35.574 LOG_DBG[1584]dsm_badge_granted_access(): Getting Grant Access due to badge call to door: door01

12/06/12 17:47:35.574 LOG_DBG[1588]dsm_badge_granted_access(): door: door01, first_unlock_flag: 0, pending_mode_change: 0

12/06/12 17:47:35.726 LOG_DBG[5486]main(): Lock Open Event!!

12/06/12 17:47:35.727 LOG_DBG[5495]main(): Found Lock m00/output01/lock in Door Id: 0

12/06/12 17:47:35.728 LOG_DBG[5639]main(): Type: 2

12/06/12 17:47:35.729 LOG_DBG[0360]dsm_door_thread_input_mesg(): !! Sending Request to Door thread: 0

12/06/12 17:47:35.729 LOG_DBG[5229]main(): Waiting for Event Input

12/06/12 17:47:35.730 LOG_DBG[1174]invoke_dsm(): Type: 2

12/06/12 17:47:35.731 LOG_DBG[1175]invoke_dsm(): In invoke_dsm(), type: 2, input: 1, input_value: 1

12/06/12 17:47:35.732 LOG_DBG[0086]dispatch_door_device_event(): device_type:3

12/06/12 17:47:35.732 LOG_DBG[2381]simple_dsm_handle_lock_input(): Door Id: 0, Simple DSM handle Lock Input

12/06/12 17:47:35.733 LOG_INFO[0275]acev_post_event(): ev_len 296 acev_evinfo_t 156 acev_svc_t 172 ix 336

12/06/12 17:47:35.733 LOG_DBG[0667]dsm_door_ev_gen(): Generating Door: door01 Event Id: 0x01000007, Door Unlocked

12/06/12 17:47:35.734 LOG_DBG[2489]simple_dsm_handle_lock_input(): Door Id: 0, Why is the Lock giving Unlock even though the Door is Forced Open

12/06/12 17:47:35.746 LOG_DBG[5327]main(): !!!!! Got some Commtask IPC!!!!!

12/06/12 17:47:35.747 LOG_DBG[4664]dsm_handle_commtask_ipc(): Commtask IPC received!!

12/06/12 17:47:35.747 LOG_DBG[4718]dsm_handle_commtask_ipc(): Device Name: m00/rdr01/reader, command: 4106, length: 16

12/06/12 17:47:35.748 LOG_DBG[5229]main(): Waiting for Event Input

12/06/12 17:47:35.759 LOG_DBG[5327]main(): !!!!! Got some Commtask IPC!!!!!

12/06/12 17:47:35.760 LOG_DBG[4664]dsm_handle_commtask_ipc(): Commtask IPC received!!

12/06/12 17:47:35.760 LOG_DBG[4718]dsm_handle_commtask_ipc(): Device Name: m00/output01/lock, command: 4142, length: 17

12/06/12 17:47:35.761 LOG_DBG[5229]main(): Waiting for Event Input

==> acev.log.1 <==

12/06/12 17:47:35.692 LOG_DBG[1890]acev_gen_event(): got event id 0x04000019

12/06/12 17:47:35.693 LOG_DBG[1890]acev_gen_event(): got event id 0x0301010a

12/06/12 17:47:35.741 LOG_DBG[1890]acev_gen_event(): got event id 0x01000007

==> acev.log.1 <==

12/06/12 17:47:37.714 LOG_DBG[1356]acev_encode_done(): Encoded XML message: 1007c870 1034 <?xml version="1.0" encoding="UTF-8"?>

<events functionId="notify" serviceId="EVENT" msgType="REQUEST" reqSeqNo="5">

   <event source="/Nicira/gw_FOC1550833R/m00/rdr01/reader" seqNumber="47" evtid="50331913" flag="2" priority="1" debugNodeId="10" debugPolicyHandle="33751041" retry="false">

      <timeStamp sec="1354844855" usec="448482"/>

      <devAttr>

         <genTime sec="1354844856" usec="1354844856"/>

         <badgeData HIbadgeId="0" LObadgeId="2496" credTmplId="8650756" facilityCode="55"/>

      </devAttr>

   </event>

   <event source="/Nicira/gw_FOC1550833R/Door/door01" seqNumber="48" evtid="16777224" flag="2" priority="2" debugNodeId="10" debugPolicyHandle="33751041" retry="false">

      <timeStamp sec="1354844855" usec="570809"/>

      <doorAttr mode="LOCK" state="DSM_DOOR_HELD_OPEN" accessLevelId="8388619" accessLevelReason="2" allowReason="0" triggerDevice="m00/rdr01/reader">

         <badgeData HIbadgeId="0" LObadgeId="2496" credTmplId="8650756" facilityCode="55"/>

      </doorAttr>

   </event>

</events>

==> acev.log.1 <==

12/06/12 17:47:40.717 LOG_DBG[0355]acev_proc_ev_ack(): Proc Ack Credits 2248 Holdq depth 2

12/06/12 17:47:40.717 LOG_DBG[0390]acev_proc_ev_ack(): Holdq found 1

12/06/12 17:47:40.718 LOG_DBG[0390]acev_proc_ev_ack(): Holdq found 0

12/06/12 17:47:40.731 LOG_DBG[1890]acev_gen_event(): got event id 0x0400001a

12/06/12 17:47:40.738 LOG_DBG[1890]acev_gen_event(): got event id 0x03010109

12/06/12 17:47:40.746 LOG_DBG[1890]acev_gen_event(): got event id 0x0400001f

12/06/12 17:47:40.807 LOG_DBG[1890]acev_gen_event(): got event id 0x01000006

==> bp_msg.log.1 <==

12/06/12 17:47:40.649 LOG_INFO[3596]handle_device_command(): Command 4140 for device m00/output01/lock

12/06/12 17:47:40.650 LOG_INFO[2202]lock_cmd_handler(): Lock issued on m00/output01

12/06/12 17:47:40.700 LOG_ERR[1211]spi_read_thread(): SPI driver read return ffffffff

12/06/12 17:47:40.704 LOG_DBG[1705]process_card_event(): InterfaceEvent from card 1. IntfType 6, Index 1, Ev 26

12/06/12 17:47:40.705 LOG_INFO[1656]post_raw_intf_event(): Posting raw IntfEvent 0x400001a for m00/output01. EvLen 16, InfoLen 0

12/06/12 17:47:40.705 LOG_INFO[0275]acev_post_event(): ev_len 168 acev_evinfo_t 156 acev_svc_t 172 ix 208

12/06/12 17:47:40.706 LOG_INFO[0186]post_device_event(): Posting Device Event 0x3010109 for m00/output01/lock

12/06/12 17:47:40.707 LOG_INFO[0275]acev_post_event(): ev_len 172 acev_evinfo_t 156 acev_svc_t 172 ix 212

12/06/12 17:47:40.708 LOG_INFO[1767]process_command_resp(): CMDResp: Card 1, Cookie 2000000d, Type 6, Index 1, Resp 1, Infolen 0

12/06/12 17:47:40.708 LOG_INFO[0833]post_command_response(): Posting CmdResp. Command 4140, Dev m00/output01/lock, RespCode 1, AppId 1, SvcId 5, Infolen 0

12/06/12 17:47:40.716 LOG_DBG[1705]process_card_event(): InterfaceEvent from card 1. IntfType 4, Index 1, Ev 31

12/06/12 17:47:40.716 LOG_INFO[1656]post_raw_intf_event(): Posting raw IntfEvent 0x400001f for m00/rdr01. EvLen 21, InfoLen 5

12/06/12 17:47:40.719 LOG_INFO[0275]acev_post_event(): ev_len 173 acev_evinfo_t 156 acev_svc_t 172 ix 213

12/06/12 17:47:40.720 LOG_INFO[0696]reader_ev_handler(): rd_cred:Got all 1 frames. Decoding..

12/06/12 17:47:40.720 LOG_DBG[1120]rd_cred_get_card_data(): PROCESSING Reader data frames = 1 devtmplid = 8650780

12/06/12 17:47:40.721 LOG_DBG[1123]rd_cred_get_card_data(): Input frm  0 size = 2

12/06/12 17:47:40.721 LOG_DBG[2007]rd_cred_get_dev_cred_ref_list(): Got the dev tmpl id match

12/06/12 17:47:40.722 LOG_DBG[0792]rd_cred_get_card_data_one(): *** size of cred data: 2

12/06/12 17:47:40.722 LOG_DBG[0805]rd_cred_get_card_data_one(): *** tmpl len: 26

12/06/12 17:47:40.723 LOG_DBG[0806]rd_cred_get_card_data_one(): *** tmpl type: 1

12/06/12 17:47:40.723 LOG_DBG[0807]rd_cred_get_card_data_one(): *** tmpl name:

12/06/12 17:47:40.724 LOG_DBG[0809]rd_cred_get_card_data_one(): *** eval mode return: 1

12/06/12 17:47:40.724 LOG_ERR[0855]rd_cred_get_card_data_one(): *** error code is 0

12/06/12 17:47:40.725 LOG_ERR[1154]rd_cred_get_card_data(): *** error code is 1

12/06/12 17:47:40.725 LOG_INFO[0705]reader_ev_handler(): rd_cred: Duress Keys in DevTmpl = 0

12/06/12 17:47:40.726 LOG_ERR[0734]reader_ev_handler(): rd_cred:Cred decode failed. Code 1

12/06/12 17:47:40.768 LOG_INFO[3596]handle_device_command(): Command 4108 for device m00/rdr01/reader

12/06/12 17:47:40.769 LOG_INFO[0970]reader_cmd_handler(): TerminateAccess issued on m00/rdr01. Profile is now 0

12/06/12 17:47:40.830 LOG_INFO[1767]process_command_resp(): CMDResp: Card 1, Cookie 2000000e, Type 4, Index 1, Resp 1, Infolen 0

12/06/12 17:47:40.831 LOG_INFO[0833]post_command_response(): Posting CmdResp. Command 4108, Dev m00/rdr01/reader, RespCode 1, AppId 1, SvcId 5, Infolen 0

==> dsm_exec.log.1 <==

12/06/12 17:47:40.630 LOG_DBG[0138]simple_dsm_handle_timeout_callback(): Relock Timeout for Door: 0, Name: door01

12/06/12 17:47:40.630 LOG_DBG[0102]dsm_device_lock_cmd(): Lock_cmd for device: m00/output01/lock

12/06/12 17:47:40.631 LOG_DBG[0117]dsm_device_lock_cmd(): done lock cmd 4140 156

12/06/12 17:47:40.632 LOG_DBG[0187]simple_dsm_handle_timeout_callback(): DSM Reader Grant Access Timeout for Door: 0, Name: door01

12/06/12 17:47:40.633 LOG_DBG[0200]dsm_device_reader_cmd():  Reader cmd for device: m00/rdr01/reader

12/06/12 17:47:40.633 LOG_DBG[0226]dsm_device_reader_cmd(): done Reader cmd: 4108

12/06/12 17:47:40.743 LOG_DBG[5327]main(): !!!!! Got some Commtask IPC!!!!!

12/06/12 17:47:40.744 LOG_DBG[4664]dsm_handle_commtask_ipc(): Commtask IPC received!!

12/06/12 17:47:40.744 LOG_DBG[4718]dsm_handle_commtask_ipc(): Device Name: m00/output01/lock, command: 4140, length: 17

12/06/12 17:47:40.745 LOG_DBG[5229]main(): Waiting for Event Input

12/06/12 17:47:40.792 LOG_DBG[5483]main(): Lock Closed Event!!

12/06/12 17:47:40.793 LOG_DBG[5495]main(): Found Lock m00/output01/lock in Door Id: 0

12/06/12 17:47:40.794 LOG_DBG[5639]main(): Type: 2

12/06/12 17:47:40.794 LOG_DBG[0360]dsm_door_thread_input_mesg(): !! Sending Request to Door thread: 0

12/06/12 17:47:40.795 LOG_DBG[5229]main(): Waiting for Event Input

12/06/12 17:47:40.796 LOG_DBG[1174]invoke_dsm(): Type: 2

12/06/12 17:47:40.796 LOG_DBG[1175]invoke_dsm(): In invoke_dsm(), type: 2, input: 2, input_value: 2

12/06/12 17:47:40.797 LOG_DBG[0086]dispatch_door_device_event(): device_type:3

12/06/12 17:47:40.797 LOG_DBG[2381]simple_dsm_handle_lock_input(): Door Id: 0, Simple DSM handle Lock Input

12/06/12 17:47:40.799 LOG_INFO[0275]acev_post_event(): ev_len 296 acev_evinfo_t 156 acev_svc_t 172 ix 336

12/06/12 17:47:40.799 LOG_DBG[0667]dsm_door_ev_gen(): Generating Door: door01 Event Id: 0x01000006, Door Locked

12/06/12 17:47:40.800 LOG_DBG[0514]simple_dsm_find_remove_relock_timer(): Simple DSM Find/Remove Relock Timeout, Door Id: 0

12/06/12 17:47:40.859 LOG_DBG[5327]main(): !!!!! Got some Commtask IPC!!!!!

12/06/12 17:47:40.860 LOG_DBG[4664]dsm_handle_commtask_ipc(): Commtask IPC received!!

[wetwombat]

Handy info to have, thank you Gerald.